<html>
 <head>
  <meta charset="UTF-8">
 </head>
 <body>
  <h3 data-lake-id="gl73M" id="gl73M"><span data-lake-id="uc53562d7" id="uc53562d7">问题发现</span></h3>
  <p data-lake-id="ufcca467f" id="ufcca467f"><br></p>
  <p data-lake-id="uc34808a4" id="uc34808a4"><span data-lake-id="u770726e7" id="u770726e7">线上兼容系统报警，提示有频繁的FullGC以及GC耗时问题比较严重。</span></p>
  <p data-lake-id="uc6154e46" id="uc6154e46"><span data-lake-id="ue00e6483" id="ue00e6483">​</span><br></p>
  <p data-lake-id="u423470a5" id="u423470a5"><img src="https://cdn.nlark.com/yuque/0/2024/png/5378072/1705373094495-ad9083b9-6d90-4624-ae55-fac90ff24fe8.png?x-oss-process=image%2Fwatermark%2Ctype_d3F5LW1pY3JvaGVp%2Csize_21%2Ctext_SmF2YSA4IEd1IFA%3D%2Ccolor_FFFFFF%2Cshadow_50%2Ct_80%2Cg_se%2Cx_10%2Cy_10"></p>
  <h3 data-lake-id="zKtIL" id="zKtIL"><span data-lake-id="ud68f72ec" id="ud68f72ec">问题定位</span></h3>
  <p data-lake-id="u97b1f6e1" id="u97b1f6e1"><br></p>
  <p data-lake-id="uf036ea00" id="uf036ea00"><span data-lake-id="u85c5901a" id="u85c5901a">在收到FullGC报警之后，登录到内部的监控系统，看一下集群整体的GC情况（如果没有这样的监控系统，可以去机器上查看GC日志）：</span></p>
  <p data-lake-id="u1f3ce1e4" id="u1f3ce1e4"><span data-lake-id="ub98697cf" id="ub98697cf">​</span><br></p>
  <p data-lake-id="u9447fbb9" id="u9447fbb9"><img src="https://cdn.nlark.com/yuque/0/2024/png/5378072/1705373148732-fd807c4f-f310-4f4f-94db-4b04eb839378.png?x-oss-process=image%2Fwatermark%2Ctype_d3F5LW1pY3JvaGVp%2Csize_36%2Ctext_SmF2YSA4IEd1IFA%3D%2Ccolor_FFFFFF%2Cshadow_50%2Ct_80%2Cg_se%2Cx_10%2Cy_10"></p>
  <p data-lake-id="u732d17f9" id="u732d17f9"><br></p>
  <p data-lake-id="u6d6e697e" id="u6d6e697e"><span data-lake-id="u43e57049" id="u43e57049">从图中可以看到，从大概9:03分开始，对内存的老年代就一直在涨，并且在9:13的时候发生了很多次fullGC。</span></p>
  <p data-lake-id="u7e2a428d" id="u7e2a428d"><br></p>
  <p data-lake-id="ub0f4e02b" id="ub0f4e02b"><span data-lake-id="u0d4d7f47" id="u0d4d7f47">这时候，第一时间去把堆dump下来了，我先在GC前做了一次Dump，然后再做了一次GC，然后做了一次Dump，发现GC前的Dump中很多String占用了比较多的内存，但是GC后就都被回收了。</span></p>
  <p data-lake-id="u80c72e5e" id="u80c72e5e"><span data-lake-id="ufbed42ab" id="ufbed42ab">​</span><br></p>
  <p data-lake-id="u5abe4fa3" id="u5abe4fa3"><span data-lake-id="ua520a494" id="ua520a494">然后去看这些字符串都是啥，但是很遗憾，没看出什么特别有价值的东西，都是一些游离的字符串（一方面通过堆dump发现他们不可达，另外发现FullGC后就直接回收了）</span></p>
  <p data-lake-id="u87afa7e8" id="u87afa7e8"><span data-lake-id="u384326ed" id="u384326ed">​</span><br></p>
  <p data-lake-id="ud2a89b77" id="ud2a89b77"><span data-lake-id="u1e62f443" id="u1e62f443">这时候就在分析，为啥会发生这样的情况。于是我怀疑，可能是因为在9:00-9:20这段时间，请求量比较大，创建了很多对象分配到年轻代，但是年轻代不够了，就被分配到老年代。然后老年代一直在GC，但是因为同时又有大量的操作导致对象也在不断往老年代去。所以看上去老年代在9:13分左右的GC效果并不明显。</span></p>
  <p data-lake-id="uecb7b538" id="uecb7b538"><span data-lake-id="u38c06a14" id="u38c06a14">​</span><br></p>
  <p data-lake-id="u6c9ed85f" id="u6c9ed85f"><span data-lake-id="u1235ce20" id="u1235ce20">为了验证这个猜想，同时看了下年轻代的情况，Eden区没啥明显变化，但是Survivor区的增长比较大：</span></p>
  <p data-lake-id="uf3d32f6c" id="uf3d32f6c"><span data-lake-id="u49753b0c" id="u49753b0c">​</span><br></p>
  <p data-lake-id="udcac1d4f" id="udcac1d4f"><img src="https://cdn.nlark.com/yuque/0/2024/png/5378072/1705373223501-5f649db3-2335-49fe-a4a4-2958f522ef25.png?x-oss-process=image%2Fwatermark%2Ctype_d3F5LW1pY3JvaGVp%2Csize_23%2Ctext_SmF2YSA4IEd1IFA%3D%2Ccolor_FFFFFF%2Cshadow_50%2Ct_80%2Cg_se%2Cx_10%2Cy_10"></p>
  <p data-lake-id="u8e37d958" id="u8e37d958"><br></p>
  <p data-lake-id="u308274cb" id="u308274cb"><span data-lake-id="ud6e37350" id="ud6e37350">于是感觉这个方向是靠谱的，大概率是这段时间的请求量太大了，导致很多对象被分配到老年代，然后触发了很多次FullGC。</span></p>
  <p data-lake-id="ufed4bf30" id="ufed4bf30"><span data-lake-id="u403a7f28" id="u403a7f28">​</span><br></p>
  <p data-lake-id="ub93cdff9" id="ub93cdff9"><span data-lake-id="u6536703a" id="u6536703a">于是开始看系统监控，找这段时间有没有哪些接口或者请求的量比较大。</span></p>
  <p data-lake-id="udfe283a5" id="udfe283a5"><span data-lake-id="u66295c4f" id="u66295c4f">​</span><br></p>
  <p data-lake-id="u606a7982" id="u606a7982"><span data-lake-id="u94fe2513" id="u94fe2513">1、先是翻了我们的RPC接口的调用量监控，发现并无异常。</span></p>
  <p data-lake-id="u83c10c87" id="u83c10c87"><span data-lake-id="u1d6f26ab" id="u1d6f26ab">2、继续翻了MQ的消费量监控，发现并无异常。</span></p>
  <p data-lake-id="ub456de99" id="ub456de99"><span data-lake-id="u336f940b" id="u336f940b">3、查看对外部接口的调用量监控，发现有一个接口的调用量QPS比较高。</span></p>
  <p data-lake-id="ufc29c542" id="ufc29c542"><span data-lake-id="uad47a6fe" id="uad47a6fe">​</span><br></p>
  <p data-lake-id="u0bdbc641" id="u0bdbc641"><img src="https://cdn.nlark.com/yuque/0/2024/png/5378072/1705373703428-650e7c95-4eeb-4cfc-9205-b840b93b028e.png?x-oss-process=image%2Fwatermark%2Ctype_d3F5LW1pY3JvaGVp%2Csize_23%2Ctext_SmF2YSA4IEd1IFA%3D%2Ccolor_FFFFFF%2Cshadow_50%2Ct_80%2Cg_se%2Cx_10%2Cy_10"></p>
  <p data-lake-id="u77a80644" id="u77a80644"><br></p>
  <p data-lake-id="ue0bc1d1f" id="ue0bc1d1f"><span data-lake-id="u3d45a0c4" id="u3d45a0c4">4、查看TDDL的QPS（TDDL是阿里内部的数据库访问中间件，可以简单认为是数据库连接池）飙高明显。</span></p>
  <p data-lake-id="uc4bb3de6" id="uc4bb3de6"><span data-lake-id="u9bdbf07c" id="u9bdbf07c">​</span><br></p>
  <p data-lake-id="uc56713c7" id="uc56713c7"><img src="https://cdn.nlark.com/yuque/0/2024/png/5378072/1705373673899-979feaae-4ff5-4392-b07f-508d30856ef2.png?x-oss-process=image%2Fwatermark%2Ctype_d3F5LW1pY3JvaGVp%2Csize_22%2Ctext_SmF2YSA4IEd1IFA%3D%2Ccolor_FFFFFF%2Cshadow_50%2Ct_80%2Cg_se%2Cx_10%2Cy_10"></p>
  <p data-lake-id="uc81abd85" id="uc81abd85"><br></p>
  <p data-lake-id="u504f29bf" id="u504f29bf"><span data-lake-id="u2d268063" id="u2d268063">结合这两个现象，一个是具体哪个接口调用量变大了，一个是哪张表的写操作变多了。而且时间也刚好对得上，于是就继续分析。</span></p>
  <p data-lake-id="uc93b43d9" id="uc93b43d9"><span data-lake-id="u0733bdf3" id="u0733bdf3">​</span><br></p>
  <p data-lake-id="u6cb4bb59" id="u6cb4bb59"><span data-lake-id="u27090a0e" id="u27090a0e">开始找这部分代码的调用链，发现是一个定时任务，扫表进行数据操作的。而且时间也对得上，每小时执行一次，基本上是在整点开始执行，大概15分钟执行完。</span></p>
  <p data-lake-id="u8666801c" id="u8666801c"><span data-lake-id="u2b0d6ed1" id="u2b0d6ed1">​</span><br></p>
  <p data-lake-id="u9486f859" id="u9486f859"><span data-lake-id="uc187ee0c" id="uc187ee0c">这里交代一下背景，我们的定时任务是分布式任务，也就是说比如有10000条数据，会有10台机器并发去扫描这些数据来处理。</span></p>
  <p data-lake-id="ua74318c3" id="ua74318c3"><span data-lake-id="uec802b64" id="uec802b64">​</span><br></p>
  <p data-lake-id="ud4c75b39" id="ud4c75b39"><span data-lake-id="u6858b325" id="u6858b325">这里奇怪的是只有一台机器有这个FullGC以及堆被干满的情况，这不应该啊。于是我开始逐台机器查看他最近12小时的堆内存情况。</span></p>
  <p data-lake-id="u0db07fdc" id="u0db07fdc"><span data-lake-id="ud8baaa1d" id="ud8baaa1d">​</span><br></p>
  <p data-lake-id="ud935c3fc" id="ud935c3fc"><span data-lake-id="u68e32f9f" id="u68e32f9f">还真让我发现了一个规律，那就是在不同的时间点，都会有其中某台机器的内存升高，有的时候会有FullGC，有的时候没有，而且基本都是在整点左右开始，并且也伴随着前面发现的TDDL和接口的调用量飙升。</span></p>
  <p data-lake-id="u3690776a" id="u3690776a"><span data-lake-id="u305e6403" id="u305e6403">​</span><br></p>
  <p data-lake-id="ud6742469" id="ud6742469"><span data-lake-id="u04e2f017" id="u04e2f017">以下是另外一台机器在前一天19点左右的堆内存及GC情况。</span></p>
  <p data-lake-id="u4001d43b" id="u4001d43b"><img src="https://cdn.nlark.com/yuque/0/2024/png/5378072/1705373985131-863c535e-6907-4a88-ae4c-a1df9dd63e96.png?x-oss-process=image%2Fwatermark%2Ctype_d3F5LW1pY3JvaGVp%2Csize_22%2Ctext_SmF2YSA4IEd1IFA%3D%2Ccolor_FFFFFF%2Cshadow_50%2Ct_80%2Cg_se%2Cx_10%2Cy_10"></p>
  <p data-lake-id="u3b77e0c4" id="u3b77e0c4"><br></p>
  <p data-lake-id="u4001f173" id="u4001f173"><br></p>
  <p data-lake-id="u48aa2925" id="u48aa2925"><span data-lake-id="u47427f96" id="u47427f96">再来总结一下现象：</span></p>
  <p data-lake-id="u93cf8a9a" id="u93cf8a9a"><span data-lake-id="u0bb794a8" id="u0bb794a8">​</span><br></p>
  <p data-lake-id="u6f7ae019" id="u6f7ae019"><span data-lake-id="ua5df04b9" id="ua5df04b9">1、每个整点开始，会有一个扫表任务开始执行，任务是分布式，多台机器并发开始执行。</span></p>
  <p data-lake-id="u287118c0" id="u287118c0"><span data-lake-id="u3531bcc9" id="u3531bcc9">2、任务开始执行后，会有某台机器的老年代内存被干满，导致频繁的FullGC</span></p>
  <p data-lake-id="u88e0f1e3" id="u88e0f1e3"><span data-lake-id="ucd3a4b91" id="ucd3a4b91">3、GC是有效果的，说明这些对象都是垃圾对象。可以被回收的。那就是因为年轻代放不下了导致的，而不是内存泄漏。</span></p>
  <p data-lake-id="ue61a8d3a" id="ue61a8d3a"><span data-lake-id="u65ef4c2b" id="u65ef4c2b">​</span><br></p>
  <p data-lake-id="uc913de59" id="uc913de59"><span data-lake-id="ub37a1179" id="ub37a1179">到这里，聪明的我马上想到了问题可能出在哪了。（机智脸</span></p>
  <p data-lake-id="u978d2a9a" id="u978d2a9a"><span data-lake-id="u929b17e3" id="u929b17e3">​</span><br></p>
  <p data-lake-id="ud7c0c851" id="ud7c0c851"><span data-lake-id="ucac875e0" id="ucac875e0">然后我开始验证我的想法，找到一个整点时间点，然后去看这个整点之后的15分钟内，有堆内催增长的机器，和没有堆内存增长（或者增长不明显）的机器，对比日志。</span></p>
  <p data-lake-id="u2abc3a5d" id="u2abc3a5d"><span data-lake-id="ufcf87eb4" id="ufcf87eb4">​</span><br></p>
  <p data-lake-id="uc0a9c97c" id="uc0a9c97c"><span data-lake-id="ub5f82a40" id="ub5f82a40">假设：9：00是11.11.11.11这台机器FullGC了， 10：00 是22.22.22.22这台机器FullGC了。</span></p>
  <p data-lake-id="u91b7a3e6" id="u91b7a3e6"><span data-lake-id="u7ae45e2d" id="u7ae45e2d">​</span><br></p>
  <p data-lake-id="ufaaf5382" id="ufaaf5382"><span data-lake-id="udf2a6d5d" id="udf2a6d5d">那么就这么对比：</span></p>
  <p data-lake-id="uec06ab56" id="uec06ab56"><span data-lake-id="ucb1b533e" id="ucb1b533e">​</span><br></p>
  <p data-lake-id="ud3924b5d" id="ud3924b5d"><span data-lake-id="u15b4fe6d" id="u15b4fe6d">11.11.11.11机器在9:00 - 10:00之间的日志，和，11.11.11.11机器在8：00-9：00之间的日志对比。</span></p>
  <p data-lake-id="u37ef354f" id="u37ef354f"><span data-lake-id="ud65beccc" id="ud65beccc">1.11.11.11机器在9:00 - 10:00之间的日志，和，22.22.22.22机器在10：00-11：00之间的日志对比。</span></p>
  <p data-lake-id="u66ba7592" id="u66ba7592"><span data-lake-id="ud985aad2" id="ud985aad2">​</span><br></p>
  <p data-lake-id="ud21719ff" id="ud21719ff"><span data-lake-id="u41dafb85" id="u41dafb85">然后我就发现了问题：</span></p>
  <p data-lake-id="uea20551d" id="uea20551d"><span data-lake-id="u65f44d9b" id="u65f44d9b">​</span><br></p>
  <p data-lake-id="u325da24b" id="u325da24b"><span data-lake-id="ub664f834" id="ub664f834">11.11.11.11机器在9:00 - 10:00之间和22.22.22.22机器在10：00-11：00之间扫描的数据范围是一样的，都是用户ID以22作为开头的数据。</span></p>
  <p data-lake-id="u6544096e" id="u6544096e"><span data-lake-id="ua2575ad3" id="ua2575ad3">​</span><br></p>
  <p data-lake-id="u78285866" id="u78285866"><span data-lake-id="u875f3fec" id="u875f3fec">因为我们是分布式任务扫表，为了扫表不重复，所以会根据用户ID的前两位进行分段，然后随机给不同的机器去扫描不同的前缀的用户。</span></p>
  <p data-lake-id="u1b55f3aa" id="u1b55f3aa"><span data-lake-id="u4502c5c7" id="u4502c5c7">​</span><br></p>
  <p data-lake-id="u87d50ab3" id="u87d50ab3"><span data-lake-id="u85507b79" id="u85507b79">刚好22开头的用户太多（数据严重倾斜）导致分到这段的机器就要处理大量数据，处理过程中会创建很多对象，导致内存被占用。然后因为随机分的，所以不同的时段会有不同的机器内存被干满。</span></p>
  <p data-lake-id="ucca54309" id="ucca54309"><span data-lake-id="uba808cd9" id="uba808cd9">​</span><br></p>
  <p data-lake-id="udda06429" id="udda06429"><span data-lake-id="u868bc3fc" id="u868bc3fc">可以看到22开头的明显比别的多很多：</span></p>
  <p data-lake-id="ucd321426" id="ucd321426"><img src="https://cdn.nlark.com/yuque/0/2024/png/5378072/1705376325424-fb817c4f-738c-4622-bc70-7d5666967956.png?x-oss-process=image%2Fwatermark%2Ctype_d3F5LW1pY3JvaGVp%2Csize_31%2Ctext_SmF2YSA4IEd1IFA%3D%2Ccolor_FFFFFF%2Cshadow_50%2Ct_80%2Cg_se%2Cx_10%2Cy_10"></p>
  <p data-lake-id="ud806c6ad" id="ud806c6ad"><br></p>
  <p data-lake-id="u4b597eb1" id="u4b597eb1"><span data-lake-id="u4bb8dccc" id="u4bb8dccc">如下图，是一台6:00-7:00之间有FullGC的机器的日志情况：</span></p>
  <p data-lake-id="uc2f98912" id="uc2f98912"><img src="https://cdn.nlark.com/yuque/0/2024/png/5378072/1705377149520-5e8f70bc-e605-48c4-bd1b-0acf6dba2b14.png?x-oss-process=image%2Fwatermark%2Ctype_d3F5LW1pY3JvaGVp%2Csize_94%2Ctext_SmF2YSA4IEd1IFA%3D%2Ccolor_FFFFFF%2Cshadow_50%2Ct_80%2Cg_se%2Cx_10%2Cy_10"></p>
  <p data-lake-id="u70f378a7" id="u70f378a7"><br></p>
  <h3 data-lake-id="iemXy" id="iemXy"><span data-lake-id="ue2651d04" id="ue2651d04">问题解决</span></h3>
  <p data-lake-id="u9df2d195" id="u9df2d195"><br></p>
  <p data-lake-id="u14658330" id="u14658330"><span data-lake-id="u01e51552" id="u01e51552">问题定位到了，解决就容易了，想办法让倾斜的数据在分布式任务扫表的时候均分就行了。有几个办法：</span></p>
  <p data-lake-id="u43cd1c91" id="u43cd1c91"><span data-lake-id="udcc675a4" id="udcc675a4">​</span><br></p>
  <p data-lake-id="u7c6e5edd" id="u7c6e5edd"><span data-lake-id="ucfd28759" id="ucfd28759">1、之前是按照用户ID前两位分的，那么就再分的细一点，按照前3位分一下。</span></p>
  <p data-lake-id="u29b34f68" id="u29b34f68"><span data-lake-id="u7d0ae014" id="u7d0ae014">2、不再按照用户ID分，而是按照主键ID进行分段。（</span><span data-lake-id="u5d55590f" id="u5d55590f" class="lake-fontsize-12" style="color: rgba(25, 26, 31, 0.9)">最开始没用这个方案是因为待扫描数据并不连续，区间长度不太好掌握，还有个重要原因就是需要在SQL中针对相同用户做数据聚合。</span><span data-lake-id="u6e7c0bac" id="u6e7c0bac">）</span></p>
  <p data-lake-id="ue81756e1" id="ue81756e1"><span data-lake-id="u67c63cdd" id="u67c63cdd">​</span><br></p>
 </body>
</html>